ASoC: SOF: loader: print DSP boot time in debug prints#5418
ASoC: SOF: loader: print DSP boot time in debug prints#5418kv2019i wants to merge 2 commits intothesofproject:topic/sof-devfrom
Conversation
There was a problem hiding this comment.
Pull Request Overview
The PR adds debug prints to measure and log DSP firmware boot time in the SOF loader.
- Introduces a timestamp capture at boot start using ktime_get().
- Logs firmware boot completion with elapsed time, and similarly logs post-boot completion time after calling post_fw_boot().
kv2019i
force-pushed
the
202505-log-dsp-boot
branch
from
e54d15f to
64cfde0
Compare
sound/soc/sof/loader.c
Outdated
|
|
||
| return 0; | ||
| dev_dbg(sdev->dev, "firmware boot (post) complete, took %lldus\n", | ||
| ktime_us_delta(ktime_get(), boot_start)); |
There was a problem hiding this comment.
I think this is pointless to print out if the ops->post_fw_boot is not set, I would move it inside of the if() and print it only if ret == 0 with "Full firmware startup took %lldus\n".
Or you might want to break it down to firmware boot proper and post boot time.
There was a problem hiding this comment.
I started making these changes, but then changed my mind. post_fw_boot has the additional steps on Intel (IPC4) platforms, but there are also extra steps in snd_sof_dsp_post_fw_run(), and given these prints are added to common code, shouldn't we cover all the post boot steps in the measured time (DSP post_boot and IPC-version dependent post_boot)...?
Or is this too Intel specific and we should hide these prints to some more HW specific code? @dbaluta , what do you think?
It would still seem useful information to have (all platforms need to boot the FW).
There was a problem hiding this comment.
I still think that this is pointless to print if sdev->ipc->ops->post_fw_boot == NULL
Also, a theoretical log:
firmware boot complete, took 100us
firmware boot (post) complete, took 140us
the full boot time is 100us+140us or 140us? I know the answer, but from the print I assume the former, while the later is the meaning.
and w/o post_fw_boot:
firmware boot complete, took 100us
firmware boot (post) complete, took 101us
The printk took 1us, is that really something which helps?
| .state = SOF_DSP_PM_D0, | ||
| }; | ||
| .state = SOF_DSP_PM_D0, | ||
| }; |
There was a problem hiding this comment.
this should be the first patch.
There was a problem hiding this comment.
Uh, sorry, I put this last on purpose. Now fixed in updated series.
Fix to use tabs for indentation. Signed-off-by: Kai Vehmanen <kai.vehmanen@linux.intel.com>
kv2019i
force-pushed
the
202505-log-dsp-boot
branch
from
64cfde0 to
bce83c5
Compare
DSP boot time is a key contributing factor to audio device set up time with SOF. Add measurement of boot time and include it in the debug messages. Move the "firmware boot complete" message to end of the run_firmware() function and include possible post_fw_boot() actions in the boot up time. Signed-off-by: Kai Vehmanen <kai.vehmanen@linux.intel.com>
kv2019i
force-pushed
the
202505-log-dsp-boot
branch
from
bce83c5 to
083b0b0
Compare
|
New revision:
|
| return 0; | ||
| if (!ret) | ||
| dev_dbg(sdev->dev, "firmware boot complete, took %lldus\n", | ||
| ktime_us_delta(ktime_get(), boot_start)); |
There was a problem hiding this comment.
Are you fine with logging now the combined snd_sof_dsp_run() + snd_sof_dsp_post_fw_run() + sdev->ipc->ops->post_fw_boot() ?
Note: the basefw boot time can be deduced based on the timestamps in kernel log:
"booting DSP firmware"
...
"fw_state change: 6 -> 7"
| if (sdev->fw_state == SOF_FW_BOOT_READY_FAILED) | ||
| return -EIO; /* FW boots but fw_ready op failed */ | ||
|
|
||
| dev_dbg(sdev->dev, "firmware boot complete\n"); |
There was a problem hiding this comment.
The firmware boot proper is done at this point to be pragmatic, from this point we have the post boot calls, which needs a running firmware on the DSP side...
|
It's true there are many things we can measure here. Is boot time from trigger to FW_READY? Or should it include any steps to make the FW usable (e.g. post_fw_boot actions on Intel platforms)? And depending on what you are looking at, one might want to look at each step separately. I think more I think about it, a single number doesn't make sense and existing logs can be used to calculate the time already. Let me close this now. |
No description provided.